Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

trace_events: add trace category enabled tracking #22128

Closed
wants to merge 1 commit into from

Conversation

jasnell
Copy link
Member

@jasnell jasnell commented Aug 4, 2018

Track state of async_hooks trace event category enablement.
Enable/disable the async_hooks trace event dynamically.

Checklist
  • make -j4 test (UNIX), or vcbuild test (Windows) passes
  • tests and/or benchmarks are included
  • commit message follows commit guidelines

@nodejs-github-bot nodejs-github-bot added the lib / src Issues and PRs related to general changes in the lib or src directory. label Aug 4, 2018
@jasnell
Copy link
Member Author

jasnell commented Aug 4, 2018

Note: without this, the JS async_hooks trace event is not enabled if trace events are enabled dynamically at runtime.

@jasnell
Copy link
Member Author

jasnell commented Aug 4, 2018

@devsnek
Copy link
Member

devsnek commented Aug 4, 2018

so async_hooks registers a c++ callback, which gets called, emits to js, gets caught by async_hooks_trace_events, then calls back into c++ to the tracing api?

@jasnell
Copy link
Member Author

jasnell commented Aug 4, 2018

The current impl is.... Less than ideal. I'm planning to work on refactoring soon.

@jasnell
Copy link
Member Author

jasnell commented Aug 6, 2018

This was broken by the recent refactoring improvements that landed. Will have to revisit and figure out a slightly different way of doing it.

@jasnell
Copy link
Member Author

jasnell commented Aug 6, 2018

@jasnell
Copy link
Member Author

jasnell commented Aug 7, 2018

@jasnell
Copy link
Member Author

jasnell commented Aug 7, 2018

@jasnell
Copy link
Member Author

jasnell commented Aug 7, 2018

@jasnell
Copy link
Member Author

jasnell commented Aug 7, 2018

@jasnell
Copy link
Member Author

jasnell commented Aug 8, 2018

One more run on ci-lite to make sure the linting issue is resolved: https://ci.nodejs.org/job/node-test-pull-request-lite-pipeline/467/

@jasnell
Copy link
Member Author

jasnell commented Aug 8, 2018

Ping @nodejs/diagnostics @nodejs/async_hooks @nodejs/trace-events ... CI is good on this, can I get a few eyes on the PR? :-)

@jasnell jasnell requested a review from addaleax August 8, 2018 20:27
@@ -11,4 +11,4 @@ const list = process.moduleLoadList.slice();

const assert = require('assert');

assert(list.length <= 73, list);
assert(list.length <= 76, list);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not really in favor of adding 3 more modules in our bootstrap.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agree, will try to cut this down :-)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Made this a little bit better.

'use strict';

const { traceCategoryState } = process.binding('trace_events');
const { createHook } = require('internal/trace_events_async_hooks');
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you dynamically require this?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

absolutely

const asyncHooksEnabled = !!traceCategoryState[kCategoryAsyncHooks];

if (asyncHooksEnabled && !traceEventsAsyncHook) {
traceEventsAsyncHook = createHook();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In my opinion, trace_events_async_hooks.js should depend on trace_events.js. Making trace_events.js depend on trace_events_async_hooks.js makes the code very coupled.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I disagree. I think the dependency ordering actually makes more sense this way. Rather than burying the loading of trace_events_async_hooks.js inside bootstrap, it's loaded on demand only when tracing for that category is actually enabled.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it's loaded on demand only when tracing for that category is actually enabled.

This I agree with.

I think the dependency ordering actually makes more sense this way.

This I disagree with.


I don't see the connection between thoese two statements. To me, the current implementations corresponds to putting http.js code in events.js.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

With this change, the async hook is only created and enabled when the callback within internal/trace_events.js is called and the node.async_hooks category is enabled. I'm not sure how that dependency would be worked if flipped. Can you suggest an alternative approach?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

make trace_events.js an EventEmitter and make trace_events_async_hooks.js a listener.

Code not tested and didn't do any cleanup. Also didn't dynamically load trace_events_async_hooks.js. However you could do that by moving the listener to the bootstrap. It is less nice, but at least a more futureprof API.

diff --git a/lib/internal/bootstrap/node.js b/lib/internal/bootstrap/node.js
index 66d734a5b2..e93321a777 100644
--- a/lib/internal/bootstrap/node.js
+++ b/lib/internal/bootstrap/node.js
@@ -303,10 +303,12 @@
   }
 
   function setupTraceCategoryState() {
-    const { toggleTraceCategoryState } =
-       NativeModule.require('internal/trace_events');
-    toggleTraceCategoryState();
-    _setupTraceCategoryState(toggleTraceCategoryState);
+    const traceEventsModule = NativeModule.require('internal/trace_events');
+    _setupTraceCategoryState(
+      traceEventsModule.emit.bind(traceEventsModule, 'categoryStateUpdated')
+    );
+
+    NativeModule.require('internal/trace_events_async_hooks').setup();
   }
 
   function setupProcessObject() {
diff --git a/lib/internal/trace_events.js b/lib/internal/trace_events.js
index 577738466c..6b0054c45e 100644
--- a/lib/internal/trace_events.js
+++ b/lib/internal/trace_events.js
@@ -1,26 +1,6 @@
 'use strict';
 
 const { internalBinding } = require('internal/bootstrap/loaders');
-const { traceCategoryState } = internalBinding('trace_events');
-const kCategoryAsyncHooks = 0;
-let createHook;
-let traceEventsAsyncHook;
 
-function toggleTraceCategoryState() {
-  // Dynamically enable/disable the traceEventsAsyncHook
-  const asyncHooksEnabled = !!traceCategoryState[kCategoryAsyncHooks];
-
-  if (asyncHooksEnabled && !traceEventsAsyncHook) {
-    if (!createHook)
-      createHook = require('internal/trace_events_async_hooks').createHook;
-    traceEventsAsyncHook = createHook();
-    traceEventsAsyncHook.enable();
-  } else if (!asyncHooksEnabled && traceEventsAsyncHook) {
-    traceEventsAsyncHook.disable();
-    traceEventsAsyncHook = undefined;
-  }
-}
-
-module.exports = {
-  toggleTraceCategoryState
-};
+class TraceEvents extends events.EventEmitter {}
+module.exports = new TraceEvents();
diff --git a/lib/internal/trace_events_async_hooks.js b/lib/internal/trace_events_async_hooks.js
index 0b9ffed818..bcd877fee9 100644
--- a/lib/internal/trace_events_async_hooks.js
+++ b/lib/internal/trace_events_async_hooks.js
@@ -1,7 +1,8 @@
 'use strict';
 
 const { internalBinding } = require('internal/bootstrap/loaders');
-const { trace } = internalBinding('trace_events');
+const traceEvents = require('internal/bootstrap/trace_events');
+const { trace, isTraceCategoryEnabled } = internalBinding('trace_events');
 const async_wrap = process.binding('async_wrap');
 const async_hooks = require('async_hooks');
 
@@ -64,4 +65,16 @@ function createHook() {
   });
 }
 
-module.exports = { createHook };
+const hook = createHook();
+
+function setup() {
+  traceEvents.on('categoryStateUpdated', function () {
+    if (isTraceCategoryEnabled('async_hooks')) {
+      hook.enable();
+    } else {
+      hook.disable();
+    }
+  });
+}
+
+module.exports = { setup };

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not really a fan of this approach and don't see it as much of an improvement.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A file named trace_events_async_hooks.js should logically depend on trace_events and async_hooks. I wouldn't expect a file named trace_events.js to depend on async_hooks.js. This is more than just file naming, but what is intuitive in a dependency tree.

If we generalize this to more things that are going to depend on trace_events, should we then continue to inline hooks into the trace_events.js file? Wouldn't it make more sense to being able to listen to an event, in a way that doesn't couple everything into the same function?

PS: Could you please provide arguments other than "Not really a fan of this approach".

@jasnell jasnell force-pushed the trace-state branch 2 times, most recently from 904ca94 to 375de3b Compare August 9, 2018 23:00
@jasnell
Copy link
Member Author

jasnell commented Aug 9, 2018

@jasnell
Copy link
Member Author

jasnell commented Aug 9, 2018

Copy link
Member

@mcollina mcollina left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@jasnell
Copy link
Member Author

jasnell commented Aug 10, 2018

@jasnell
Copy link
Member Author

jasnell commented Aug 10, 2018

CI after yet another rebase: https://ci.nodejs.org/job/node-test-pull-request/16340/

Rerun on linuxone due to known unrelated flaky: https://ci.nodejs.org/job/node-test-commit-linuxone/3815/

@jasnell jasnell added the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label Aug 11, 2018
@jasnell
Copy link
Member Author

jasnell commented Aug 12, 2018

@mcollina ... just collapsed this in to internal/bootstrap/node.js to avoid the additional require on bootstrap.

@@ -64,4 +64,4 @@ function createHook() {
});
}

module.exports = { createHook };
module.exports = createHook;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

At least make this a singleton. Meaning module.exports = createHook();

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I had it that way in the original version but I've got concerns over the internal state tracking... Specifically, we end up with a memory leak if tracing is dynamically disabled and we still have items in the map that are waiting for a destroy. Doing it this way resets the internal state. Will think of another way of doing that.

Copy link
Member

@AndreasMadsen AndreasMadsen Aug 12, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@jasnell Thanks. That actually makes sense. But yeah, it is still wired it is not a singleton.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One approach we could take is to add a reset function to the async_hook instance. I could do that in a one off way or we could make it part of the async_hook API. Internally, the async_hook can call reset when disable is called.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@jasnell I think it is best to do it in a "one-off way". I would even consider just exposing a enable and a disable function, that simply relays to async_hooks and clears the state.

In general, I think async_hooks should be as state-free as possible. As it can get very heavy performance wise and is easily implemented in userland.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I can live with that :-) making the updates now, will push a new commit shortly

@BridgeAR
Copy link
Member

It would be great to get another review here @nodejs/diagnostics @nodejs/async_hooks @nodejs/trace-events

NativeModule.require('internal/trace_events_async_hooks');
}
traceEventsAsyncHook.enable();
} else if (!asyncHooksEnabled && traceEventsAsyncHook) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

is the !asyncHooksEnabled && necessary in the condition here?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, we only want to turn it off if that specific category is turned off

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I might be missing something, but isn't asyncHooksEnabled necessarily false on the else side of branch?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ha! Yeah you're right. I changed the if condition going in and didn't even think about that one ;)

@jasnell
Copy link
Member Author

jasnell commented Aug 14, 2018

@jasnell
Copy link
Member Author

jasnell commented Aug 15, 2018

@jasnell
Copy link
Member Author

jasnell commented Aug 15, 2018

Re-run linux-containered... again: https://ci.nodejs.org/job/node-test-commit-linux-containered/6285/

@jasnell
Copy link
Member Author

jasnell commented Aug 16, 2018

Track state of async_hooks trace event category enablement.
Enable/disable the async_hooks trace event dynamically.
@jasnell
Copy link
Member Author

jasnell commented Aug 16, 2018

one of the CI jobs failed again for unrelated reasons... rebased, squashed, trying again: https://ci.nodejs.org/job/node-test-pull-request/16496/

@jasnell
Copy link
Member Author

jasnell commented Aug 16, 2018

Good CI... finally. @AndreasMadsen can I ask you to take another look?

Copy link
Member

@AndreasMadsen AndreasMadsen left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

deleted dublicate.

Copy link
Member

@AndreasMadsen AndreasMadsen left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks Okay To Me.

I do think this would benefit from a userland consumable API to check what categories are enabled (as a list) and an event emitter for when that changes.

The kCategoryAsyncHooks and setupTraceCategoryState is very customized for async_hooks. I often find hard to reason about that kind of complexity.

@jasnell
Copy link
Member Author

jasnell commented Aug 17, 2018

A userland API is in my list of todos as we progress. I don't want to enable that too soon because there's still quite a bit of churn in the trace events stuff and categories/formats/apis are likely to continue to evolve. Once those settle down and become more stable, exposing user facing APIs that can be depended upon becomes much easier :-)

Thank you for the review @AndreasMadsen ! :-)

jasnell added a commit that referenced this pull request Aug 17, 2018
Track state of async_hooks trace event category enablement.
Enable/disable the async_hooks trace event dynamically.

PR-URL: #22128
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Andreas Madsen <amwebdk@gmail.com>
@jasnell
Copy link
Member Author

jasnell commented Aug 17, 2018

Landed in 4b7cd4b

@jasnell jasnell closed this Aug 17, 2018
@@ -311,6 +302,32 @@
}
}

function setupTraceCategoryState() {
const { traceCategoryState } = internalBinding('trace_events');
const kCategoryAsyncHooks = 0;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Apologies that I took so long to do a full review. Post-landing LGTM w/ the following comment, which can be addressed as a follow-on.

AFAICT, this 0 is a hard-coded constant that appears here and also at env.cc:109. Is it possible to define this symbolically somewhere?

@targos targos added backport-requested-v10.x and removed author ready PRs that have at least one approval, no pending requests for changes, and a CI started. labels Aug 19, 2018
@targos
Copy link
Member

targos commented Aug 19, 2018

Should this be backported to v10.x-staging? If yes please follow the guide and raise a backport PR, if not let me know or add the dont-land-on label.

@jasnell
Copy link
Member Author

jasnell commented Aug 19, 2018

Yes it needs to be landed in 10.x

@targos
Copy link
Member

targos commented Aug 29, 2018

Do you plan to backport it or should we open an issue to ask for help?

@targos
Copy link
Member

targos commented Sep 2, 2018

Ping

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
lib / src Issues and PRs related to general changes in the lib or src directory.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

8 participants